Skip to content

fix: synchronize prefixed output writer to fix concurrent-write panic - #2949

Open
ankit090701 wants to merge 1 commit into
go-task:mainfrom
ankit090701:fix/prefixed-output-concurrent-write-race
Open

fix: synchronize prefixed output writer to fix concurrent-write panic#2949
ankit090701 wants to merge 1 commit into
go-task:mainfrom
ankit090701:fix/prefixed-output-concurrent-write-race

Conversation

@ankit090701

Copy link
Copy Markdown

What's the bug

With output: prefixed enabled, Task can panic while a command writes to stdout and stderr concurrently:

panic: runtime error: slice bounds out of range [2687:2453]

goroutine 178 [running]:
bytes.(*Buffer).readSlice(...)
        bytes/buffer.go:440
bytes.(*Buffer).ReadString(...)
        bytes/buffer.go:459
github.com/go-task/task/v3/internal/output.(*prefixWriter).writeOutputLines(0xc0001bab90, 0x0)
        github.com/go-task/task/v3@v3.43.3/internal/output/prefixed.go:58 +0x3a
github.com/go-task/task/v3/internal/output.(*prefixWriter).Write(...)
        github.com/go-task/task/v3@v3.43.3/internal/output/prefixed.go:49 +0x45
io.copyBuffer(...)
        io/io.go:431
os/exec.(*Cmd).writerDescriptor.func1()
        os/exec/exec.go:580

Reproduces with:

version: "3"
output: prefixed
tasks:
  default:
    cmds:
      - |
        for i in $(seq 1 10000); do
          echo "stdout line ${i}" &
          echo "stderr line ${i}" >&2 &
        done
        wait

Root cause

WrapWriter in internal/output/prefixed.go returns the same *prefixWriter instance for both stdout and stderr:

pw := &prefixWriter{writer: stdOut, prefix: prefix, prefixed: p}
return pw, pw, func(error) error { return pw.close() }

os/exec copies a running command's stdout and stderr to their respective writers from two separate goroutines (io.copyBuffer in Cmd.writerDescriptor), so for prefixed output, Write can legitimately be called concurrently on the same prefixWriter by both the stdout- and stderr-copying goroutines of a single task. prefixWriter.Write and writeOutputLines read and write pw.buff (a bytes.Buffer) without any synchronization, and bytes.Buffer is explicitly documented as not safe for concurrent use - concurrent access corrupts its internal length/offset bookkeeping, which is exactly what produces a "slice bounds out of range" panic.

Note that Prefixed.mutex already exists and is held in writeLine, but it only protects the struct shared across all prefixes (the seen map and counter) - it does nothing to protect an individual prefixWriter's own buffer from its two concurrent callers.

The fix

Add a sync.Mutex to prefixWriter and hold it for the full duration of both Write and close (both of which read/mutate pw.buff). This is a distinct, narrower lock than Prefixed.mutex, so there's no risk of the two interacting or deadlocking - writeOutputLines (called while holding prefixWriter.mutex) calls writeLine, which acquires the separate Prefixed.mutex.

Testing

  • Added TestPrefixedConcurrentStdoutStderr (internal/output/output_test.go): spawns two goroutines writing 5000 lines each to stdout and stderr concurrently through the same prefixed writer, then calls cleanup.
  • Verified with go test -race: without the fix, this reliably reproduces both the underlying data race and the exact reported panic (slice bounds out of range) within a handful of runs. With the fix, it passes cleanly (no race, no panic) across repeated runs (-count=5, and again in isolation with -race).
  • Ran the full test suite (go build ./... && go vet ./... && go test ./...) - clean aside from TestEvaluateSymlinksInPaths, which I confirmed is unrelated: it fails the same way with a filesystem/symlink error on an unmodified checkout too, due to how real NTFS symlinks don't survive a Windows→Linux Docker bind mount (I don't have a native Go toolchain on this machine, so I built/tested via Docker).

Fixes #2945

WrapWriter in internal/output/prefixed.go returns the same *prefixWriter
instance for both a task's stdout and stderr:

    pw := &prefixWriter{writer: stdOut, prefix: prefix, prefixed: p}
    return pw, pw, func(error) error { return pw.close() }

os/exec copies a running command's stdout and stderr to their respective
writers from two separate goroutines, so for the "prefixed" output mode,
Write can legitimately be called concurrently on the same prefixWriter by
both the stdout- and stderr-copying goroutines of a single task.
prefixWriter.Write and writeOutputLines read and write pw.buff (a
bytes.Buffer) without any synchronization, and bytes.Buffer is not safe
for concurrent use, so this corrupts its internal state and can panic -
reported as "slice bounds out of range" - whenever a command produces
enough concurrent stdout/stderr output.

Add a mutex to prefixWriter and hold it for the duration of both Write
and close, matching the pattern already used for the separate
Prefixed.mutex that protects the shared prefix/counter map (which does
not, on its own, protect each writer's buffer).

Added TestPrefixedConcurrentStdoutStderr, which spawns two goroutines
writing thousands of lines to stdout and stderr concurrently through the
same prefixed writer. Verified under `go test -race`: without the fix,
this reliably reproduces the exact reported panic (and the underlying
data race); with the fix, it passes cleanly across repeated runs.

Fixes go-task#2945

Signed-off-by: ankit090701 <ankitanku090701@gmail.com>

@trulede trulede left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Your testing demonstrated the effectiveness of the fix. Great!

Its probably a good idea to limit when the test runs.

prefixed *Prefixed
prefix string
buff bytes.Buffer
mutex sync.Mutex

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Its quite often abbreviated to 'mu' rather than mutex. I don't mind personally, just mentioning.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@C:\Users\AnkitPrasad\Desktop\Test\scratchpad_mu_reply.md

@ankit090701

Copy link
Copy Markdown
Author

Thanks! Before guessing at what to change, I actually measured it and checked a couple of things:

  • Timing: TestPrefixedConcurrentStdoutStderr (5000 lines × 2 goroutines) runs in 0.01s plain, 0.20s under -race (whole go test -race ./internal/output/... invocation including instrumentation overhead is ~1.2s). So it's not adding meaningful wall-clock cost to the suite either way.
  • I also checked: ci.yml and the test task in Taskfile.yml both run plain go test ./... — this repo's CI doesn't currently invoke -race anywhere. That matters here specifically because in plain (non-race) mode this test only catches the bug probabilistically (via the actual panic, which needs enough concurrent unsynchronized writes to occur before it — reliable within a handful of runs per my testing, but not deterministic every single execution), whereas under -race it's a deterministic, guaranteed-if-present signal.

Given it's not a cost problem, I want to make sure I address what you actually meant rather than guess:

  • Did you mean skip/gate it in some context (e.g. -short)? This repo doesn't use testing.Short() anywhere yet, so I didn't want to introduce that convention unprompted.
  • Or is the concern more that a plain (non--race) run doesn't give a hard guarantee, so it'd be better only enabled when race detection is on?

Let me know which (or something else) and I'll push it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

panic in prefixed output when stdout and stderr are written concurrently

2 participants